<html>
 <head>
  <meta charset="UTF-8">
 </head>
 <body>
  <p data-lake-id="ubc86880a" id="ubc86880a"><span data-lake-id="u8998e785" id="u8998e785">前段时间我们新上了一个新的应用，因为流量一直不大，集群QPS大概只有5左右，写接口的rt在30ms左右。</span></p>
  <p data-lake-id="ue09c70a0" id="ue09c70a0"><br></p>
  <p data-lake-id="u0e18ddbe" id="u0e18ddbe"><span data-lake-id="u6961864c" id="u6961864c">因为最近接入了新的业务，业务方给出的数据是日常QPS可以达到2000，大促峰值QPS可能会达到1万。</span></p>
  <p data-lake-id="u138c92ef" id="u138c92ef"><br></p>
  <p data-lake-id="u32ab020e" id="u32ab020e"><span data-lake-id="u42d7cb7a" id="u42d7cb7a">所以，为了评估水位，我们进行了一次压测。压测在预发布环境执行。压测过程中发现，当单机QPS达到200左右时，接口的rt没有明显变化，但是CPU利用率急剧升高，直到被打满。</span></p>
  <p data-lake-id="uaf85cbd5" id="uaf85cbd5"><br></p>
  <p data-lake-id="u78162430" id="u78162430"><img src="http://www.hollischuang.com/wp-content/uploads/2021/03/16165515783925-scaled.jpg?x-oss-process=image%2Fwatermark%2Ctype_d3F5LW1pY3JvaGVp%2Csize_73%2Ctext_SmF2YSA4IEd1IFA%3D%2Ccolor_FFFFFF%2Cshadow_50%2Ct_80%2Cg_se%2Cx_10%2Cy_10"></p>
  <p data-lake-id="ud68a41d6" id="ud68a41d6"><br></p>
  <p data-lake-id="ub93e4872" id="ub93e4872"><span data-lake-id="uc98912e7" id="uc98912e7">压测停止后，CPU利用率立刻降了下来。</span></p>
  <p data-lake-id="u5a87bcee" id="u5a87bcee"><br></p>
  <p data-lake-id="ud31fa5ff" id="ud31fa5ff"><span data-lake-id="u0ff35d2d" id="u0ff35d2d">于是开始排查是什么导致了CPU的飙高。</span></p>
  <p data-lake-id="u330cb048" id="u330cb048"><br></p>
  <h3 data-lake-id="04bf00e3" id="04bf00e3"><span data-lake-id="u69ba17cb" id="u69ba17cb">问题排查与解决</span></h3>
  <p data-lake-id="u79cd467a" id="u79cd467a"><br></p>
  <p data-lake-id="u689538d7" id="u689538d7"><span data-lake-id="udfe0f239" id="udfe0f239">在压测期间，登录到机器，开始排查问题。</span></p>
  <p data-lake-id="u0f2f0327" id="u0f2f0327"><br></p>
  <p data-lake-id="u71728a48" id="u71728a48"><span data-lake-id="u2ab05116" id="u2ab05116">本案例的排查过程使用的阿里开源的Arthas工具进行的，不使用arthas，使用JDK自带的命令也是可以。</span></p>
  <p data-lake-id="u7f14ac80" id="u7f14ac80"><br></p>
  <p data-lake-id="u491f32af" id="u491f32af"><span data-lake-id="ucb6de07d" id="ucb6de07d">在开始排查之前，可以先看一下CPU的使用情况，最简单的就是使用top命令直接查看：</span></p>
  <p data-lake-id="u00ee6af8" id="u00ee6af8"><br></p>
  <pre lang="java"><code>
top - 10:32:38 up 11 days, 17:56,  0 users,  load average: 0.84, 0.33, 0.18
Tasks:  23 total,   1 running,  21 sleeping,   0 stopped,   1 zombie
%Cpu(s): 95.5 us,  2.2 sy,  0.0 ni, 76.3 id,  0.0 wa,  0.0 hi,  0.0 si,  6.1 st
KiB Mem :  8388608 total,  4378768 free,  3605932 used,   403908 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  4378768 avail Mem
   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND  
   3480 admin     20   0 7565624   2.9g   8976 S  241.2 35.8 649:07.23 java  
   1502 root      20   0  401768  40228   9084 S   1.0  0.5  39:21.65 ilogtail
   181964 root      20   0 3756408 104392   8464 S   0.7  1.2   0:39.38 java   
   496 root      20   0 2344224  14108   4396 S   0.3  0.2  52:22.25 staragentd  
   1400 admin     20   0 2176952 229156   5940 S   0.3  2.7  31:13.13 java
   235514 root      39  19 2204632  15704   6844 S   0.3  0.2  55:34.43 argusagent
   236226 root      20   0   55836   9304   6888 S   0.3  0.1  12:01.91 systemd-journ
</code></pre>
  <p data-lake-id="ua52e2c75" id="ua52e2c75"><br></p>
  <p data-lake-id="u86b3e1d6" id="u86b3e1d6"><span data-lake-id="u58f9e405" id="u58f9e405">可以看到，进程ID为3480的Java进程占用的CPU比较高，基本可以断定是应用代码执行过程中消耗了大量CPU，接下来开始排查具体是哪个线程，哪段代码比较耗CPU。</span></p>
  <p data-lake-id="u8a6be6d9" id="u8a6be6d9"><br></p>
  <p data-lake-id="ucec8a690" id="ucec8a690"><span data-lake-id="u4e4353f9" id="u4e4353f9">首先，下载Arthas命令：</span></p>
  <p data-lake-id="u2dadcabf" id="u2dadcabf"><br></p>
  <pre lang="java"><code>
curl -L https://arthas.aliyun.com/install.sh | sh
</code></pre>
  <p data-lake-id="ue49d073c" id="ue49d073c"><br></p>
  <p data-lake-id="uae4ed832" id="uae4ed832"><span data-lake-id="u5e3bc54d" id="u5e3bc54d">启动</span></p>
  <p data-lake-id="uc6ff8939" id="uc6ff8939"><br></p>
  <pre lang="java"><code>
./as.sh
</code></pre>
  <p data-lake-id="ud1a8e89a" id="ud1a8e89a"><br></p>
  <p data-lake-id="ua233befc" id="ua233befc"><span data-lake-id="u405f64c5" id="u405f64c5">使用Arthas命令"thread -n 3 -i 1000"查看当前"最忙"（耗CPU）的三个线程：</span></p>
  <p data-lake-id="u50768233" id="u50768233"><br></p>
  <p data-lake-id="u992c5cce" id="u992c5cce"><img src="http://www.hollischuang.com/wp-content/uploads/2021/03/16165659820207.jpg?x-oss-process=image%2Fwatermark%2Ctype_d3F5LW1pY3JvaGVp%2Csize_65%2Ctext_SmF2YSA4IEd1IFA%3D%2Ccolor_FFFFFF%2Cshadow_50%2Ct_80%2Cg_se%2Cx_10%2Cy_10"></p>
  <p data-lake-id="ub0b1a73b" id="ub0b1a73b"><br></p>
  <p data-lake-id="u9dbdc7af" id="u9dbdc7af"><span data-lake-id="u156e9fc5" id="u156e9fc5">通过上面的堆栈信息，可以看出，占用CPU资源的线程主要是卡在JDBC底层的TCP套接字读取上。连续执行了很多次，发现很多线程都是卡在这个地方。</span></p>
  <p data-lake-id="u902dded1" id="u902dded1"><br></p>
  <p data-lake-id="u2fcfc1f2" id="u2fcfc1f2"><span data-lake-id="u6e9fa303" id="u6e9fa303">通过分析调用链，发现这个地方是我代码中有数据库的insert，并且使用TDDL来创建sequence，在sequence的创建过程中需要和数据库有交互。</span></p>
  <p data-lake-id="uef67272f" id="uef67272f"><br></p>
  <p data-lake-id="ud88db498" id="ud88db498"><span data-lake-id="u0c116b99" id="u0c116b99">但是，基于对TDDL的了解，TDDL每次从数据库中查询sequence序列的时候，默认会取出1000条，缓存在本地，只有用完之后才会再从数据库获取下一个1000条序列。</span></p>
  <p data-lake-id="u2768bb46" id="u2768bb46"><br></p>
  <p data-lake-id="u49c7a831" id="u49c7a831"><span data-lake-id="u2b0f93a9" id="u2b0f93a9">按理说我们的压测QPS只有300左右，不应该这么频繁的何数据库交互才对。但是，经过多次使用arthas的查看，发现大部分CPU都耗尽在这里。</span></p>
  <p data-lake-id="u217de76e" id="u217de76e"><br></p>
  <p data-lake-id="uad5c0a88" id="uad5c0a88"><span data-lake-id="u2abca472" id="u2abca472">于是开始排查代码问题。最终发现了一个很傻的问题，那就是我们的sequence创建和使用有问题：</span></p>
  <p data-lake-id="uddc3ec06" id="uddc3ec06"><br></p>
  <pre lang="java"><code>
public Long insert(T dataObject) {

    if (dataObject.getId() == null) {
        Long id = next();
        dataObject.setId(id);
    }

    if (sqlSession.insert(getNamespace() + ".insert", dataObject) &gt; 0) {
        return dataObject.getId();
    } else {
        return null;
    }
}

public Sequence sequence() {
    return SequenceBuilder.create()
        .name(getTableName())
        .sequenceDao(sequenceDao)
        .build();
}

/**
 * 获取下一个主键ID
 *
 * @return
 */
protected Long next() {
    try {
        return sequence().nextValue();
    } catch (SequenceException e) {
        throw new RuntimeException(e);
    }
}
</code></pre>
  <p data-lake-id="uaceb3215" id="uaceb3215"><br></p>
  <p data-lake-id="ud34d01fa" id="ud34d01fa"><span data-lake-id="ua28d1e73" id="ua28d1e73">是因为，我们每次insert语句都重新build了一个新的sequence，这就导致本地缓存就被丢掉了，所以每次都会去数据库中重新拉取1000条，但是只是用了一条，下一次就又重新取了1000条，周而复始。</span></p>
  <p data-lake-id="ue6e79a99" id="ue6e79a99"><br></p>
  <p data-lake-id="u3c9668ce" id="u3c9668ce"><span data-lake-id="ued277989" id="ued277989">于是，调整了代码，把Sequence实例的生成改为在应用启动时初始化一次。这样后面在获取sequence的时候，不会每次都和数据库交互，而是先查本地缓存，本地缓存的耗尽了才会再和数据库交互，获取新的sequence。</span></p>
  <p data-lake-id="udacddb37" id="udacddb37"><br></p>
  <pre lang="java"><code>
public abstract class BaseMybatisDAO implements InitializingBean {
        @Override
        public void afterPropertiesSet() throws Exception {
            sequence = SequenceBuilder.create().name(getTableName()).sequenceDao(sequenceDao).build();
        }
    }
</code></pre>
  <p data-lake-id="u6c993d27" id="u6c993d27"><br></p>
  <p data-lake-id="ub5b12718" id="ub5b12718"><span data-lake-id="u5065f7cd" id="u5065f7cd">通过实现InitializingBean，并且重写afterPropertiesSet()方法，在这个方法中进行Sequence的初始化。</span></p>
  <p data-lake-id="ufb6b0f4d" id="ufb6b0f4d"><br></p>
  <p data-lake-id="u76cc7a5c" id="u76cc7a5c"><span data-lake-id="u497a003a" id="u497a003a">改完以上代码，提交进行验证。通过监控数据可以看出优化后，数据库的读RT有明显下降：</span></p>
  <p data-lake-id="u91e15741" id="u91e15741"><br></p>
  <p data-lake-id="u1a5f1899" id="u1a5f1899"><img src="http://www.hollischuang.com/wp-content/uploads/2021/03/16165777571485.jpg?x-oss-process=image%2Fwatermark%2Ctype_d3F5LW1pY3JvaGVp%2Csize_21%2Ctext_SmF2YSA4IEd1IFA%3D%2Ccolor_FFFFFF%2Cshadow_50%2Ct_80%2Cg_se%2Cx_10%2Cy_10"></p>
  <p data-lake-id="ub78c0e8e" id="ub78c0e8e"><br></p>
  <p data-lake-id="ude42aff9" id="ude42aff9"><span data-lake-id="ubce6f2e7" id="ubce6f2e7">sequence的写操作QPS也有明显下降：</span></p>
  <p data-lake-id="ud0968d57" id="ud0968d57"><br></p>
  <p data-lake-id="uc74f3525" id="uc74f3525"><img src="http://www.hollischuang.com/wp-content/uploads/2021/03/16165777883205.jpg?x-oss-process=image%2Fwatermark%2Ctype_d3F5LW1pY3JvaGVp%2Csize_22%2Ctext_SmF2YSA4IEd1IFA%3D%2Ccolor_FFFFFF%2Cshadow_50%2Ct_80%2Cg_se%2Cx_10%2Cy_10"></p>
  <p data-lake-id="u1dbcd1c5" id="u1dbcd1c5"><br></p>
  <p data-lake-id="u1ef2a096" id="u1ef2a096"><span data-lake-id="ue6accf51" id="ue6accf51">于是我们开始了新的一轮压测，但是发现，CPU的使用率还是很高，压测的QPS还是上不去，于是重新使用Arthas查看线程的情况。</span></p>
  <p data-lake-id="ue657d68a" id="ue657d68a"><br></p>
  <p data-lake-id="u695baa5c" id="u695baa5c"><img src="http://www.hollischuang.com/wp-content/uploads/2021/03/16165667534840.jpg?x-oss-process=image%2Fwatermark%2Ctype_d3F5LW1pY3JvaGVp%2Csize_29%2Ctext_SmF2YSA4IEd1IFA%3D%2Ccolor_FFFFFF%2Cshadow_50%2Ct_80%2Cg_se%2Cx_10%2Cy_10"></p>
  <p data-lake-id="u7b3af3e6" id="u7b3af3e6"><br></p>
  <p data-lake-id="ubf6db948" id="ubf6db948"><span data-lake-id="u14c9385e" id="u14c9385e">发现了一个新的比较耗费CPU的线程的堆栈，这里面主要是因为我们用到了一个联调工具，该工具预发布默认开启了TDDL的采集（官方文档中描述为预发布默认不开启TDDL采集，但是实际上会采集）。</span></p>
  <p data-lake-id="u7ee29e58" id="u7ee29e58"><br></p>
  <p data-lake-id="u7710b278" id="u7710b278"><span data-lake-id="ub6f4fbf6" id="ub6f4fbf6">这个工具在打印日志过程中会进行脱敏，脱敏框架会调用Google的re2j进行正则表达式的匹配。</span></p>
  <p data-lake-id="u839a93e2" id="u839a93e2"><br></p>
  <p data-lake-id="ud7552b43" id="ud7552b43"><span data-lake-id="u6c52a210" id="u6c52a210">因为我的操作中TDDL操作比较多，默认采集大量TDDL日志并且进行脱敏处理，确实比较耗费CPU。</span></p>
  <p data-lake-id="uec97694f" id="uec97694f"><br></p>
  <p data-lake-id="u3ebe276c" id="u3ebe276c"><span data-lake-id="u5d734b2e" id="u5d734b2e">所以，通过在预发布中关闭DP对TDDL的采集，即可解决该问题。</span></p>
  <p data-lake-id="u751d89f2" id="u751d89f2"><br></p>
  <h3 data-lake-id="cb7fbe75" id="cb7fbe75"><span data-lake-id="u842560e9" id="u842560e9">总结与思考</span></h3>
  <p data-lake-id="uf51c6a09" id="uf51c6a09"><br></p>
  <p data-lake-id="u4ddd14a5" id="u4ddd14a5"><span data-lake-id="u64cb21ee" id="u64cb21ee">本文总结了一次线上CPU飙高的问题排查过程，其实问题都不难，并且还挺傻的，但是这个排查过程是值得大家学习的。</span></p>
  <p data-lake-id="u3325cfbe" id="u3325cfbe"><br></p>
  <p data-lake-id="u70821eae" id="u70821eae"><span data-lake-id="uc8fc4797" id="uc8fc4797">其实在之前自己排查过很多次CPU飙高的问题，这次也是按照老方法进行排查，但是刚开始并没有发现太大的问题，只是以为是流量升高导致数据库操作变多的正常现象。</span></p>
  <p data-lake-id="u5661c0d3" id="u5661c0d3"><br></p>
  <p data-lake-id="u27a891e4" id="u27a891e4"><span data-lake-id="u91bb955d" id="u91bb955d">期间又多方查证（通过arthas查看sequence的获取内容、通过数据库查看最近插入的数据的主键ID等）才发现是TDDL的Sequence的初始化机制有问题。</span></p>
  <p data-lake-id="u9e8e2f92" id="u9e8e2f92"><br></p>
  <p data-lake-id="u564ee8e5" id="u564ee8e5"><span data-lake-id="u6aed7d08" id="u6aed7d08">在解决了这个问题之后，以为彻底解决问题，结果又遇到了DP采集TDDL日志导致CPU飙高，最终再次解决后有了明显提升。</span></p>
  <p data-lake-id="u88f7c02e" id="u88f7c02e"><br></p>
  <p data-lake-id="ued90782a" id="ued90782a"><span data-lake-id="u34b30c11" id="u34b30c11">所以，事出反常必有妖，排查问题就是一个抽丝剥茧的过程。</span></p>
 </body>
</html>